chore: log process id instead of logging name #2100

paulyufan2 · 2023-08-02T01:48:55Z

Reason for Change:

This PR is to get rid of repeated "logger: azure-vnet" name. Instead, it will print the process id, such as : "pid":301

Issue Fixed:

New logs on Linux:

{"level":"info","ts":"2023-08-11T02:14:30.471Z","msg":"Plugin Info","pid":299160,"name":"azure-vnet","version":"v1.5.9-9-gd589d7df","component":"cni-net"}
2023/08/11 02:14:30 [299160] [net] Restored state
{"level":"info","ts":"2023-08-11T02:14:30.471Z","msg":"Plugin started","pid":299160,"component":"cni-net"}
{"level":"info","ts":"2023-08-11T02:14:30.471Z","msg":"[cni-net] Processing ADD command","pid":299160,"containerId":"0ffde0741e3e96ac0394991ae0fa86f01ffdcb39acdd0877c04843de7a8f7a6d","netNS":"/var/run/netns/cni-039e1fc6-101e-4e19-692d-645048038cb0","ifName":"eth0","args":"K8S_POD_UID=38b85cf6-29ea-4357-90ef-45a3360717d8;IgnoreUnknown=1;K8S_POD_NAMESPACE=default;K8S_POD_NAME=linux-pod2;K8S_POD_INFRA_CONTAINER_ID=0ffde0741e3e96ac0394991ae0fa86f01ffdcb39acdd0877c04843de7a8f7a6d","path":"/opt/cni/bin","stdinData":"{\"cniVersion\":\"0.3.0\",\"ipam\":{\"mode\":\"overlay\",\"type\":\"azure-cns\"},\"ipsToRouteViaHost\":[\"169.254.20.10\"],\"mode\":\"transparent\",\"name\":\"azure\",\"type\":\"azure-vnet\"}"}
{"level":"info","ts":"2023-08-11T02:14:30.472Z","msg":"[cni-net] Found network with subnet","pid":299160,"network":"azure","subnet":"10.244.0.0/16"}
{"level":"info","ts":"2023-08-11T02:14:30.472Z","msg":"linux-pod2","pid":299160}
{"level":"info","ts":"2023-08-11T02:14:30.472Z","msg":"Requesting IP for pod using ipconfig","pid":299160,"pod":{"PodName":"linux-pod2","PodNamespace":"default"},"ipconfig":{"desiredIPAddresses":null,"podInterfaceID":"0ffde074-eth0","infraContainerID":"0ffde0741e3e96ac0394991ae0fa86f01ffdcb39acdd0877c04843de7a8f7a6d","orchestratorContext":{"PodName":"linux-pod2","PodNamespace":"default"},"ifname":""}}
{"level":"info","ts":"2023-08-11T02:14:30.476Z","msg":"Received info for pod",**"pid":299160**,"ipv4info":{},"podInfo":{"PodName":"linux-pod2","PodNamespace":"default"},"component":"cni-invoker-cns"}
{"level":"info","ts":"2023-08-11T02:14:30.476Z","msg":"Received info for pod","pid":299160,"ipv4info":{},"podInfo":{"PodName":"linux-pod2","PodNamespace":"default"},"component":"cni-invoker-cns"}
{"level":"info","ts":"2023-08-11T02:14:30.477Z","msg":"[cni-net] Creating endpoint","pid":299160,"endpointInfo":"Id:0ffde074-eth0 ContainerID:0ffde0741e3e96ac0394991ae0fa86f01ffdcb39acdd0877c04843de7a8f7a6d NetNsPath:/var/run/netns/cni-039e1fc6-101e-4e19-692d-645048038cb0 IfName:eth0 IfIndex:0 MacAddr: IPAddrs:[{10.244.1.71 ffff0000} {fdad:db03:a8b6:1a06::154 ffffffffffffffff0000000000000000}] Gateways:[] Data:map[vethname:default.linux-pod2]"}

New logs on Windows:
{"level":"info","ts":"2023-08-11T02:27:30.090Z","msg":"Plugin started","pid":5112,"component":"cni-net"}
{"level":"info","ts":"2023-08-11T02:27:30.090Z","msg":"[cni-net] Processing DEL command","pid":5112,"containerId":"a02bd997aaec32e8356286bc6411eb7ba6ed273bf7140716eacf35965233e46a","netNS":"c46f1949-30b1-4d44-be62-6ac58263d28c","ifName":"eth0","args":"IgnoreUnknown=1;K8S_POD_NAMESPACE=kube-system;K8S_POD_NAME=csi-azurefile-node-win-5xrfh;K8S_POD_INFRA_CONTAINER_ID=a02bd997aaec32e8356286bc6411eb7ba6ed273bf7140716eacf35965233e46a;K8S_POD_UID=e9aa3235-0205-4372-871e-56ada83c6ae0","path":"c:/k/azurecni/bin","stdinData":"{"AdditionalArgs":[{"Name":"EndpointPolicy","Value":{"ExceptionList":["10.244.0.0/16"],"Type":"OutBoundNAT"}},{"Name":"EndpointPolicy","Value":{"ExceptionList":["fdad:db03:a8b6:1a06::/64"],"Type":"OutBoundNAT"}},{"Name":"EndpointPolicy","Value":{"Action":"Block","Direction":"Out","Priority":200,"Protocols":"6","RemoteAddresses":"168.63.129.16/32","RemotePorts":"80","RuleType":"Switch","Type":"ACL"}},{"Name":"EndpointPolicy","Value":{"Action":"Allow","Direction":"In","Priority":65500,"Type":"ACL"}},{"Name":"EndpointPolicy","Value":{"Action":"Allow","Direction":"Out","Priority":65500,"Type":"ACL"}}],"bridge":"azure0","capabilities":{"dns":true,"portMappings":true},"cniVersion":"0.3.0","dns":{"Nameservers":["10.0.0.10","168.63.129.16"],"Search":["svc.cluster.local"]},"executionMode":"v4swift","ipam":{"mode":"v4overlay","type":"azure-cns"},"mode":"bridge","name":"azure","runtimeConfig":{"dns":{"Servers":["10.0.0.10"],"Searches":["kube-system.svc.cluster.local","svc.cluster.local","cluster.local"],"Options":["ndots:5"]}},"type":"azure-vnet","windowsSettings":{"enableLoopbackDSR":true}}"}
{"level":"info","ts":"2023-08-11T02:27:30.091Z","msg":"Execution mode","pid":5112,"mode":"v4swift"}
{"level":"info","ts":"2023-08-11T02:27:30.091Z","msg":"[cni-net] Endpoints to be deleted","pid":5112,"count":1}
{"level":"error","ts":"2023-08-11T02:27:30.091Z","msg":"[cni-net] Failed to query network","pid":5112,"network":"azure","error":"Network not found"}
{"level":"info","ts":"2023-08-11T02:27:30.091Z","msg":"[cni-net] DEL command completed","pid":5112,"pod":"csi-azurefile-node-win-5xrfh"}
{"level":"info","ts":"2023-08-11T02:27:30.091Z","msg":"Plugin stopped","pid":5112,"component":"cni-net"}
2023/08/11 02:27:30 [5112] Released process lock

the nonsense <"logger": "azure-vnet"> is gone and "pid": is added

Requirements:

uses conventional commit messages
includes documentation
adds unit tests
relevant PR labels added

Notes:

vipul-21 · 2023-08-02T17:22:23Z

cni/log/logger.go

@@ -46,6 +47,7 @@ func newFileLogger(cfg *Config) *zap.Logger {

 	core := zapcore.NewCore(jsonEncoder, logFileWriter, logLevel)
 	Logger = zap.New(core)
+	Logger = Logger.With(zap.Int("pid", os.Getgid()))


os.Getgid() will return -1 for windows.
Also, since we are removing components name from log and now the cfg.Name as well. How will the log look like ?

Hi Vipul, you can see current log as above.

{"level":"info","ts":"2023-08-02T02:38:03.651Z","msg":"Plugin stopped","pid":0,"component":"cni-net"}, the component will be remove as per PR#2099. So the log will be {"level":"info","ts":"2023-08-02T02:38:03.651Z","msg":"Plugin stopped","pid":0,"} ? If so, how would we know that which plugin stopped ?

I think removing the component (#2099) is a mistake

Hi @rbtr As Tamilmani mentioned that CNI is mostly single threaded, so adding the component in each log is not that helpful

it doesn't matter that it is single threaded.
extra log context is meant to help you identify where in the code the log (or probably error) is coming from. "component" should describe the specific module of the CNI that is generating that log, right?

we can keep component if you guys say so. but based on my debugging experince, i never looked at component in log.

@paulyufan2 the way you are getting pid is wrong. @vipul-21 each plugin will have different log file.. if azure-vnet.log, then cni plugin, if azure-vnet-ipam.log, then its ipam plugin

@paulyufan2 Let's keep component for now and review back later. you can abandon this PR and create a PR for adding PID and remove logger name

vipul-21 · 2023-08-11T16:41:19Z

cni/log/logger.go


-	return Logger.Named(cfg.Name)
+	return Logger.Named("")


We don't need to return the Logger.Named(""). We can now just return the Logger. By default Logger is unnamed.

* get rid of logger name * change to getpid() * fix comment

paulyufan2 requested a review from a team as a code owner August 2, 2023 01:48

paulyufan2 requested review from vipul-21 and tamilmani1989 August 2, 2023 01:48

paulyufan2 force-pushed the addzaplogpid branch from 5dc5655 to 059c756 Compare August 2, 2023 01:50

paulyufan2 added the cni Related to CNI. label Aug 2, 2023

paulyufan2 changed the title ~~log process id instead of log name~~ chore: log process id instead of logging name Aug 2, 2023

vipul-21 reviewed Aug 2, 2023

View reviewed changes

paulyufan2 force-pushed the addzaplogpid branch 2 times, most recently from 186ccfd to 6c6ef47 Compare August 10, 2023 03:34

paulyufan2 force-pushed the addzaplogpid branch from 6c6ef47 to d589d7d Compare August 11, 2023 02:02

vipul-21 requested changes Aug 11, 2023

View reviewed changes

paulyufan2 enabled auto-merge (squash) August 11, 2023 17:44

vipul-21 approved these changes Aug 11, 2023

View reviewed changes

paulyufan2 added 3 commits August 11, 2023 15:53

get rid of logger name

e4d0d99

change to getpid()

e2699e4

fix comment

8176a4f

paulyufan2 force-pushed the addzaplogpid branch from f138991 to 8176a4f Compare August 11, 2023 19:53

paulyufan2 requested a review from a team as a code owner August 11, 2023 19:53

paulyufan2 requested a review from jpayne3506 August 11, 2023 21:20

rbtr approved these changes Aug 11, 2023

View reviewed changes

paulyufan2 merged commit 590b036 into master Aug 12, 2023

paulyufan2 deleted the addzaplogpid branch August 12, 2023 03:47

aggarwal0009 pushed a commit that referenced this pull request Aug 14, 2023

chore: log process id instead of logging name (#2100)

59d3f15

* get rid of logger name * change to getpid() * fix comment

aggarwal0009 pushed a commit that referenced this pull request Aug 14, 2023

chore: log process id instead of logging name (#2100)

0d3df8b

* get rid of logger name * change to getpid() * fix comment

aggarwal0009 pushed a commit that referenced this pull request Aug 14, 2023

chore: log process id instead of logging name (#2100)

4190192

* get rid of logger name * change to getpid() * fix comment

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

chore: log process id instead of logging name #2100

chore: log process id instead of logging name #2100

paulyufan2 commented Aug 2, 2023 •

edited

Loading

vipul-21 Aug 2, 2023

paulyufan2 Aug 3, 2023

vipul-21 Aug 3, 2023

rbtr Aug 3, 2023

paulyufan2 Aug 3, 2023

rbtr Aug 3, 2023

tamilmani1989 Aug 3, 2023

tamilmani1989 Aug 3, 2023

vipul-21 Aug 11, 2023

chore: log process id instead of logging name #2100

chore: log process id instead of logging name #2100

Conversation

paulyufan2 commented Aug 2, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

paulyufan2 commented Aug 2, 2023 •

edited

Loading